Repository navigation
[SLES-3037] fix: reassemble log records Lambda splits into pieces - #1415
shreyamalpani wants to merge 3 commits into
Conversation
There was a problem hiding this comment.
🟢 Approval recommended
The stitching logic is bounded, thoroughly tested, and correctly integrated with telemetry handling.
0 open findings
What changed in this PR
Reworks telemetry stitching to recover oversized Lambda log records split within or across POST payloads.
Changes:
- Detects and removes split-record seams.
- Supports multi-piece and cross-POST recovery with fallback handling.
- Adds comprehensive boundary and regression tests.
| File | Description |
|---|---|
bottlecap/src/extension/telemetry/stitch.rs |
Implements generalized record reassembly and tests. |
bottlecap/src/extension/telemetry/listener.rs |
Uses the revised stitching API. |
🧠 Review effort: Balanced
Give feedback about Copilot approvals in this survey to enter a drawing for a $150 gift card.
This comment has been minimized.
This comment has been minimized.
I'm also doing this in #1414. Feel free to approve and rebase on my changes to make your PR smaller. |
1b5eca7 to
d6f0a71
Compare
269ced9 to
b92a519
Compare
|
|
||
| /// How far past a seam's start serde can fail: a cut inside a string swallows `},{"`, and | ||
| /// the string closes on the `"` before `time`. | ||
| const SEAM_REACH: usize = 4; |
There was a problem hiding this comment.
🤖 Written by Claude, reviewed by @lym953 before posting.
The 4-byte reach misses a cut inside an object that is an array item. The payload is then discarded, and runtimeDone goes with it.
Input: the log record {"items":[{"id":1},{"id":23,"ok":true}],"n":5}, cut after {"items":[{"id":1, with both pieces in one POST:
[{"time":"2026-09-03T14:29:52.929Z","type":"function","record":{"items":[{"id":1},{"time":"2026-09-03T14:29:52.930Z","type":"function","record":},{"id":23,"ok":true}],"n":5}},{"time":"2026-09-03T14:29:52.950Z","type":"platform.runtimeDone","record":{"requestId":"abc123","status":"success"}}]Here the bytes between the pieces are valid JSON at their position:
- The first
}closes{"id":1}. - The
,starts the next array item. {"time":"...","type":"function","record":opens a new object with three keys.- Serde fails only at the
}that starts the second piece, where it expects a value.
That is 64 bytes after },{"time":" starts, so seam_at finds nothing and unsplit returns the error. This test fails on b92a519 with got Discarded:
#[test]
fn joins_pieces_of_an_array_of_objects() {
let record = r#"{"items":[{"id":1},{"id":23,"ok":true}],"n":5}"#;
let (first, rest) = record.split_at(r#"{"items":[{"id":1"#.len());
let body = format!("[{},{},{RUNTIME_DONE}]", piece("929", first), piece("930", rest));
let result = stitch(&FragmentBuffer::default(), &body);
assert!(matches!(result, Stitch::Complete(_)), "got {result:?}");
}I ran every cut position of this record (45 positions):
| Where the pieces are | Recovered | Discarded | Parsed, but with a wrong record |
|---|---|---|---|
| Two POSTs | 45 | 0 | 0 |
| One POST | 39 | 5 | 1 |
The wrong record comes from a cut inside the number 23, after {"items":[{"id":1},{"id":2. Then the whole body is valid JSON:
[{"time":"2026-09-03T14:29:52.929Z","type":"function","record":{"items":[{"id":1},{"id":2},{"time":"2026-09-03T14:29:52.930Z","type":"function","record":3,"ok":true}],"n":5}},{"time":"2026-09-03T14:29:52.950Z","type":"platform.runtimeDone","record":{"requestId":"abc123","status":"success"}}]It parses on the first try, so the stitcher never runs. The record gets an extra item made from the second envelope, and there is no error. This PR did not cause it, but it has the same cause.
RECORD in the every-cut tests has no object or array outside a string, so those tests do not reach this case. Could you add a record with an array of objects?
| } | ||
|
|
||
| /// The seam serde failed on at byte `at`, if there is one. | ||
| fn seam_at(body: &[u8], at: usize) -> Option<Range<usize>> { |
There was a problem hiding this comment.
🤖 Written by Claude, reviewed by @lym953 before posting.
A suggestion, not tested: find a cut from the bytes of the piece, not from where serde fails in the whole body.
The bytes between two pieces alone cannot show a cut. Two whole function events next to each other have the same bytes between them. In these two shortened bodies, the marked bytes are identical:
A, two whole log lines:
[{..."record":{"msg":"a"}},{"time":"T2","type":"function","record":{"msg":"b"}}]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
B, one log line cut in two:
[{..."record":{"items":[{"id":1},{"time":"T2","type":"function","record":},{"id":23}]}}]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
The difference is the record value before the marked bytes, from the event's "record": up to the marked }:
| Body | Value before the marked bytes | Does it parse alone? | So the marked bytes are |
|---|---|---|---|
| A | {"msg":"a"} |
Yes | a normal boundary, keep them |
| B | {"items":[{"id":1 |
No | a cut, remove them |
So the check could be:
- Walk the body from left to right, and find each occurrence of the marked bytes with a byte search.
- For each one, parse only the record value before it.
- If that value does not parse, remove the marked bytes.
This does not use the position of a serde failure, so body B works.
To catch the wrong-record case, this check must also run on bodies that parse. The PR description says Lambda cuts only lines longer than about 256 KiB. If that holds, the check can skip any shorter value, which keeps the cost low.
Two cases can still go wrong:
- A middle piece can be valid JSON alone, for example a piece that holds only digits. The check then takes it for a whole line.
- A customer log line can hold these bytes as real data, for example a function that logs telemetry events. The check then removes real data.
| @@ -126,7 +126,7 @@ impl TelemetryListener { | |||
| Ok(events) => events, | |||
| // The Telemetry API splits an oversized record across two POSTs, and neither half | |||
There was a problem hiding this comment.
🤖 Written by Claude, reviewed by @lym953 before posting.
nit: this comment and the first line of the stitch.rs module doc say the record is split "across two POSTs". The pieces can also be in one POST. Suggestion: "Lambda cuts a long log line into pieces, and a payload that holds a piece does not parse. See stitch."
Overview
Follow-up to #1357 (SLES-2997). That fix added
stitch.rsto recover telemetry payloads broken by an oversized log record, and raisedmaxBytesto 1 MiB. Customers on v100 still hit the same timeouts. The stitcher was in place, but their payloads never reached it.#1357 assumed the Telemetry API cuts a record at
maxBytesand resumes it in the next POST under the same envelope. That isn't what happens. Lambda itself cuts any log line longer than about 256 KiB into pieces, whatevermaxBytesis, and sends each piece as its own event with its own timestamp. For JSON log lines, each piece's raw bytes become that event's record value, so no payload containing a piece parses. The stitcher's assumptions failed in three ways:maxBytes, several pieces land in one POST. The stitcher only handled a split across two POSTs, so a single body like this was dropped.Eofparse failures were held. A cut right after a\or a complete value fails asSyntax, so it was rejected outright.So these payloads were still discarded,
platform.runtimeDonewent with them, and the on-demand loop waited until the sandbox timed out. The original repro passed because, at 256 KiBmaxBytes, each piece ended its own POST and both pieces shared a timestamp, which happens to fit the old model.Changes (extension/telemetry/stitch.rs)
}plus the next piece's envelope.Serdealways fails at, or up to 4 bytes after, a seam, which tells it apart from the boundary between two whole events. Seams only count before function/extension events, so aplatform.*event likeruntimeDoneis never absorbed.Eof) or ran into the closing}](Syntax), not onlyEof.Performance: unchanged for payloads that parse, since stitch only runs after a failed parse. Recovering a payload re-parses it once per seam, bounded by the 4 MiB fragment cap and 64 seams. That's a few ms for a ~1 MiB record, and only on payloads that previously hung the invocation.
Testing